OSS の APM！Elastic APM を使い倒す

#Elasticsearch

#Elastic Stack

藤本真司

2018.03.13

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

前回のブログエントリでは Elastic APM の魅力を全然伝えられていませんでした。機能を深掘りしてみたところ本当に OSS でいいの？と驚くような機能がたくさんありました。

概要

先日、Elastic APM の概要、導入方法をブログエントリしました。

OSS の APM！Elastic APM を試してみた

Elastic APM は OSS のパフォーマンスモニタリングツールです。前回のブログ執筆時は気づいていなかったのですが、Elastic APM はまだまだ機能がありました。中でもこの機能は知ってほしいという 3点をご紹介します。

Transaction と Span
X-Pack の専用 UI
例外検出

Transaction と Span

前回のブログエントリでは Django アプリケーションを例に Elastic APM を導入して、Web リクエストのレスポンスタイムを Kibana ダッシュボードで可視化しました。Django の設定に Elastic APM の設定を追記するだけでリクエストを受けてからレスポンスを返すまでの処理時間を計測し、Elasticsearch にストアし、Kibana で可視化できます。

ただ、レスポンスタイムを計測だけであれば、Apache や、ELB のアクセスログに出力できます。さらにログを Logstash/Fluentd などで Elasticsearch に取り込むことで簡単に Kibana で可視化できます。Elastic APM はそれだけでなく、レスポンスタイプ内の処理をより細かく計測できました。レスポンスタイムの処理を Transaction とした時にその中で実行する任意の処理単位を Span として計測できます。

イメージとしてはこんな感じ。

user が web リクエストを送信したら、web アプリケーションは各処理を実行して、user にレスポンスを返します。このレスポンスタイム内の処理が Transaction です。例えば、リクエスト内の処理で AWS の API を実行して、DB へ SQL を発行して、他の Web API へリクエストを送信したとします。これらの処理を個別に計測したい時に Span として処理をくくることでそれぞれの処理時間を計測します。

Kibana の UI で可視化すると↓のように表示されます。

Transaction 内のどの処理がどのくらいかかったのかパッと見で把握できます。

これはパフォーマンスの解析が捗りますね。

Span の実装（Python編）

Transaction と Span の関係性がわかったところで、Span の実装方法です。2つの方法で Span を定義できます。

Span のキャプチャ実装
Elastic APM のライブラリサポート

Span のキャプチャ実装

アプリケーション内の任意の関数、処理に Span を実装します。

関数の Span 実装

関数にデコレータを付与します。

import elasticapm

@elasticapm.capture_span()
def span_process():
    ANY_PROCESS

span_process 関数の始まりから終わりまでの処理時間を計測します。

処理の Span 実装

with句で Span として記録する処理を括ります。

import elasticapm

def process():
    BEFORE_PROCSS
    with elasticapm.capture_span('SPAN_NAME'):
        SPAN_PROCESS
    AFTER_PROCSS

SPAN_PROCESS の始まりから終わりまでの処理時間を計測します。

どちらも簡単ですね。ただパフォーマンスモニタリングするためにアプリケーションのソースコードを修正する必要があるのはあまり好ましくありません。。。

Elastic APM のライブラリサポート

そこで Elastic APM はいくつかのライブラリをサポートしています。サポートされたライブラリの特定の関数をトリガーに自動で Span を記録します。つまり一切ソースコードに手を加える必要がありません。ドキュメントがないのでソースコードを眺めた限りでは下記のライブラリがサポートされています。

botocore(boto3) による AWS API リクエスト
jinja2 によるテンプレートの展開
mysqlclient による MySQL へのアクセス
psycopg2 による PostgreSQL へのアクセス
pylibmc、memcached による memcached へのアクセス
pymongo による MongoDB へのアクセス
redis による Redis へのアクセス
requests、urllib3 による Web アクセス
sqlite3 による sqlite3 へのアクセス
zlib による圧縮、解凍

X-Pack の専用 UI

前回のブログエントリでは Elastic APM Server からインポートしたグラフ、ダッシュボードを UI として紹介しました。ただダッシュボードだけでは Transaction は確認しやすいのですが、Transaction 内の Span の確認がしづらいし、そもそも Kibana のグラフで分かりやすいグラフを作るのが難しいです。そこで Elastic は Elastic APM の専用UI を提供しています。X-Pack を導入することで Kibana から専用UI を閲覧できます。X-Pack は Elastic 社が提供する Elastic Stack の拡張機能です。X-Pack は有償機能／無償機能があります。Elastic APM の専用UI は無償機能となります。無償のベーシックライセンスを発行すれば利用できます。

X-Pack のインストール

X-Pack のインストールは下記エントリをご参照ください。

Elastic StackのX-Packを試す（インストール編）

専用UI の確認

Kibana へアクセスすると、左メニューに「APM」が追加されています。

登録しているサービスが一覧で表示されます。Django の設定でSERVICE_NAMEに「app」を登録したので一覧に表示されています。

settings.py

ELASTIC_APM = {
    'SERVICE_NAME': 'app',
    'SERVER_URL': 'http://10.255.0.101:8200',
    'DEBUG': True,
}

「app」を選択します。

Transaction 一覧

Transaction の一覧が表示されます。この UI は前回紹介したダッシュボードとほぼ同じなので説明は省きます。

Transaction のリンクを選択します。

Transaction 詳細（Span 一覧）

Transaction 詳細（Span 一覧）が表示されます。専用UI では特にこの Transaction の詳細からのパフォーマンス解析がしやすくなりました。

Response times（左上）
同一 Transaction の平均、95%タイル、99%タイルのレスポンスタイムが時系列で表示されます。
Requests per minute（右上）
同一 Transaction のHTTP レスポンスステータスコード単位でリクエスト数が時系列で表示されます。
Response time distribution（中）
レスポンスタイム単位の件数が表示されます。
Transaction sample（下）
ここが特に大事。色々な情報が見れます。
- Timeline では Transaction 内の各 Span の処理時間の経緯が表示されます。特定の Span のパフォーマンス低下があるケースだと解析が捗ります。
- Request ではリクエストの内容が表示されます。Body まで見れるので Body のデータ内容によってパフォーマンス低下があるケースだと解析が捗ります。